[2024-05-28T06:59:53.731154Z] [info] +++ setup notes +++
[2024-05-28T06:59:53.731385Z] [info] Running on openqaworker26:24 (Linux 5.14.21-150500.55.65-default #1 SMP PREEMPT_DYNAMIC Thu May 23 04:57:11 UTC 2024 (a46829d) x86_64)
[2024-05-28T06:59:53.736802Z] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box
[2024-05-28T06:59:53.739664Z] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box, request #237512 sent to Cache Service
[2024-05-28T06:59:58.823214Z] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box processed:
Asset "Tumbleweed.x86_64-1.0-libvirt-Snapshot20240527.vagrant.libvirt.box" was downloaded by #237511, details are therefore unavailable here
[2024-05-28T06:59:58.825048Z] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box
[2024-05-28T06:59:58.829369Z] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box, request #237513 sent to Cache Service
[2024-05-28T07:00:08.959595Z] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box processed:
[info] [#237513] Cache size of "/var/lib/openqa/cache" is 400 GiB, with limit 400 GiB
[info] [#237513] Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" from "https://openqa.opensuse.org/tests/4226811/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box"
[info] [#237513] Content of "/var/lib/openqa/cache/openqa.opensuse.org/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20240527.vagrant.virtualbox.box" has not changed, updating last use

[2024-05-28T07:00:08.961668Z] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256
[2024-05-28T07:00:08.964170Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256, request #237515 sent to Cache Service
[2024-05-28T07:00:19.071242Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256 processed:
[info] [#237515] Cache size of "/var/lib/openqa/cache" is 400 GiB, with limit 400 GiB
[info] [#237515] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" from "https://openqa.opensuse.org/tests/4226811/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256"
[info] [#237515] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso.sha256" has not changed, updating last use

[2024-05-28T07:00:19.073202Z] [debug] Found ISO, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso
[2024-05-28T07:00:19.075304Z] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso, request #237519 sent to Cache Service
[2024-05-28T07:00:24.138385Z] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso processed:
[info] [#237518] Cache size of "/var/lib/openqa/cache" is 400 GiB, with limit 400 GiB
[info] [#237518] Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" from "https://openqa.opensuse.org/tests/4226810/asset/iso/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso"
[info] [#237518] Content of "/var/lib/openqa/cache/openqa.opensuse.org/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso" has not changed, updating last use

[2024-05-28T07:00:24.141571Z] [info] Rsync from 'rsync://openqa.opensuse.org/tests' to '/var/lib/openqa/cache/openqa.opensuse.org', request #237522 sent to Cache Service
[2024-05-28T07:00:34.280073Z] [info] Output of rsync:
[info] [#237521] Calling: rsync -avHP --timeout 1800 rsync://openqa.opensuse.org/tests/ --delete /var/lib/openqa/cache/openqa.opensuse.org/tests/
Try 1:
receiving incremental file list
obs/.git/
obs/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            483 100%  471.68kB/s    0:00:00 (xfr#1, ir-chk=1158/1178)
obs/.git/index

              0   0%    0.00kB/s    0:00:00  
          2,745 100%    2.62MB/s    0:00:00 (xfr#2, ir-chk=1153/1178)
obs/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
    399,522,048  64%  381.01MB/s    0:00:00  
    616,927,137 100%  383.04MB/s    0:00:01 (xfr#3, ir-chk=1133/1178)
obs/.git/objects/
obs/.git/refs/heads/
openqa/.git/
openqa/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            554 100%    0.68kB/s    0:00:00 (xfr#4, ir-chk=1167/1450)
openqa/.git/index

              0   0%    0.00kB/s    0:00:00  
          3,093 100%    3.80kB/s    0:00:00 (xfr#5, ir-chk=1162/1450)
openqa/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     10,391,767 100%   12.07MB/s    0:00:00 (xfr#6, ir-chk=1140/1450)
openqa/.git/objects/
openqa/.git/refs/heads/
openqa/products/openqa/needles/.git/
openqa/products/openqa/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            259 100%    0.31kB/s    0:00:00 (xfr#7, ir-chk=1019/1609)
openqa/products/openqa/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
         22,443 100%   26.60kB/s    0:00:00 (xfr#8, ir-chk=1014/1609)
openqa/products/openqa/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     20,774,753 100%   22.59MB/s    0:00:00 (xfr#9, ir-chk=1002/1619)
openqa/products/openqa/needles/.git/objects/
openqa/products/openqa/needles/.git/refs/heads/
opensuse/.git/
opensuse/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
          7,264 100%    8.03kB/s    0:00:00 (xfr#10, ir-chk=1012/1698)
opensuse/.git/index

              0   0%    0.00kB/s    0:00:00  
        636,809 100%  702.69kB/s    0:00:00 (xfr#11, ir-chk=1007/1698)
opensuse/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
     28,669,198 100%   28.54MB/s    0:00:00 (xfr#12, ir-chk=1007/1717)
opensuse/.git/objects/
opensuse/.git/refs/heads/
opensuse/products/opensuse/needles/.git/
opensuse/products/opensuse/needles/.git/FETCH_HEAD

              0   0%    0.00kB/s    0:00:00  
            700  86%    0.59kB/s    0:00:00  
            810 100%    0.69kB/s    0:00:01 (xfr#13, ir-chk=1014/21413)
opensuse/products/opensuse/needles/.git/index

              0   0%    0.00kB/s    0:00:00  
      1,574,039 100%  300.22MB/s    0:00:00 (xfr#14, ir-chk=1009/21413)
opensuse/products/opensuse/needles/.git/logs/HEAD

              0   0%    0.00kB/s    0:00:00  
    123,671,376  94%  117.94MB/s    0:00:00  
    130,855,907 100%  122.71MB/s    0:00:01 (xfr#15, ir-chk=1009/21432)
opensuse/products/opensuse/needles/.git/objects/
opensuse/products/opensuse/needles/.git/refs/heads/

sent 347,803 bytes  received 1,383,524 bytes  314,786.73 bytes/sec
total size is 5,860,194,621  speedup is 3,384.80


[2024-05-28T07:00:34.280218Z] [info] Finished to rsync tests
[2024-05-28T07:00:34.285577Z] [debug] +++ worker notes +++
[37m[2024-05-28T07:00:34.628422Z] [debug] [pid:73306] Current version is 4.6.1716387241.58dd214 [interface v40][0m
[37m[2024-05-28T07:00:34.637705Z] [debug] [pid:73306] git hash in 'opensuse': 05d47c0cd70fd49af462c0598205d097904f46e3[0m
[37m[2024-05-28T07:00:34.649684Z] [debug] [pid:73306] git url in 'opensuse': https://github.com/os-autoinst/os-autoinst-distri-opensuse.git[0m
[37m[2024-05-28T07:00:34.963755Z] [debug] [pid:73306] usingenv DESKTOP=kde[0m
[37m[2024-05-28T07:00:34.963918Z] [debug] [pid:73306] usingenv DISTRI=opensuse[0m
[37m[2024-05-28T07:00:34.964017Z] [debug] [pid:73306] usingenv QEMUCPU=host[0m
[37m[2024-05-28T07:00:34.964128Z] [debug] [pid:73306] usingenv INSTLANG=en_US[0m
[37m[2024-05-28T07:00:34.964242Z] [debug] [pid:73306] usingenv DVD=1[0m
[37m[2024-05-28T07:00:34.964307Z] [debug] [pid:73306] usingenv KDE=1[0m
[37m[2024-05-28T07:00:34.964370Z] [debug] [pid:73306] usingenv ISO=openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso[0m
[37m[2024-05-28T07:00:34.964438Z] [debug] [pid:73306] usingenv ISO_MAXSIZE=4700372992[0m
[37m[2024-05-28T07:00:34.971890Z] [debug] [pid:73306] parse_vars (variables parsed from YAML schedule):[0m
[37m[2024-05-28T07:00:34.972958Z] [debug] [pid:73306] ---
  DESKTOP: gnome
  YUI_REST_API: 1
  AY_EXPAND_VARS: YUI_PORT,MIRROR_HTTP
  [0m
[37m[2024-05-28T07:00:34.973639Z] [debug] [pid:73306] ---
  - autoyast/prepare_profile
  - installation/bootloader_start
  - autoyast/installation
  - installation/yast_firstboot/firstboot_language_and_keyboard
  - installation/yast_firstboot/firstboot_welcome
  - installation/yast_firstboot/firstboot_license_agreement
  - installation/clock_and_timezone/validate_timezone_configuration
  - installation/clock_and_timezone/accept_timezone_configuration
  - installation/authentication/enable_autologin
  - installation/authentication/firstboot_user_simple_pwd
  - installation/authentication/root_simple_pwd
  - installation/yast_firstboot/firstboot_finish_setup
  - installation/first_boot
  - console/validate_yast2_firstboot_configuration
  [0m
[37m[2024-05-28T07:00:34.976262Z] [debug] [pid:73306] parse_test_suite_data (data parsed from YAML test_data):[0m
[37m[2024-05-28T07:00:34.977449Z] [debug] [pid:73306] ---
  license_agreement:
    language: English (US)
    text:
    - LICENSE AGREEMENT
  finish_setup:
    text:
    - Congratulations!
    - The installation of
    - on your machine is complete
    - Visit us at www.suse.com.
    - Have a lot of fun!
    - Your SUSE Development Team
  time_and_date:
    region: USA
    time_zone: Eastern (New York)
    hw_clock_set_to_UTC: 1
  language_and_keyboard:
    language: English (US)
    keyboard_layout: English (US)
  welcome:
    text:
    - Welcome!
    - There are a few more steps to take before your system is ready
    - YaST will now guide you through some basic configuration
  [0m
[37m[2024-05-28T07:00:34.981562Z] [debug] [pid:73306] scheduling prepare_profile tests/autoyast/prepare_profile.pm[0m
[37m[2024-05-28T07:00:34.999790Z] [debug] [pid:73306] scheduling bootloader_start tests/installation/bootloader_start.pm[0m
[37m[2024-05-28T07:00:35.002543Z] [debug] [pid:73306] scheduling installation tests/autoyast/installation.pm[0m
[37m[2024-05-28T07:00:35.006132Z] [debug] [pid:73306] scheduling firstboot_language_and_keyboard tests/installation/yast_firstboot/firstboot_language_and_keyboard.pm[0m
[37m[2024-05-28T07:00:35.007043Z] [debug] [pid:73306] scheduling firstboot_welcome tests/installation/yast_firstboot/firstboot_welcome.pm[0m
[37m[2024-05-28T07:00:35.007667Z] [debug] [pid:73306] scheduling firstboot_license_agreement tests/installation/yast_firstboot/firstboot_license_agreement.pm[0m
[37m[2024-05-28T07:00:35.008280Z] [debug] [pid:73306] scheduling validate_timezone_configuration tests/installation/clock_and_timezone/validate_timezone_configuration.pm[0m
[37m[2024-05-28T07:00:35.008759Z] [debug] [pid:73306] scheduling accept_timezone_configuration tests/installation/clock_and_timezone/accept_timezone_configuration.pm[0m
[37m[2024-05-28T07:00:35.009543Z] [debug] [pid:73306] scheduling enable_autologin tests/installation/authentication/enable_autologin.pm[0m
[37m[2024-05-28T07:00:35.010361Z] [debug] [pid:73306] scheduling firstboot_user_simple_pwd tests/installation/authentication/firstboot_user_simple_pwd.pm[0m
[37m[2024-05-28T07:00:35.011157Z] [debug] [pid:73306] scheduling root_simple_pwd tests/installation/authentication/root_simple_pwd.pm[0m
[37m[2024-05-28T07:00:35.011778Z] [debug] [pid:73306] scheduling firstboot_finish_setup tests/installation/yast_firstboot/firstboot_finish_setup.pm[0m
[37m[2024-05-28T07:00:35.012822Z] [debug] [pid:73306] scheduling first_boot tests/installation/first_boot.pm[0m
[37m[2024-05-28T07:00:35.013641Z] [debug] [pid:73306] scheduling validate_yast2_firstboot_configuration tests/console/validate_yast2_firstboot_configuration.pm[0m
[2024-05-28T07:00:35.021558Z] [info] [pid:73330] cmdsrv: daemon reachable under http://*:20243/4aPEXtdmIuNlGqc0/
[2024-05-28T07:00:35.023610Z] [info] [pid:73330] Listening at "http://[::]:20243"
Web application available at http://[::]:20243
[37m[2024-05-28T07:00:35.027604Z] [debug] [pid:73306] git hash in 'opensuse/products/opensuse/needles': 9c264ee66e0366e6bfd7b2a1d219ca52ddb44beb[0m
[37m[2024-05-28T07:00:35.044126Z] [debug] [pid:73306] git url in 'opensuse/products/opensuse/needles': git@github.com:os-autoinst/os-autoinst-needles-opensuse.git[0m
[37m[2024-05-28T07:00:35.044292Z] [debug] [pid:73306] init needles from opensuse/products/opensuse/needles[0m
[37m[2024-05-28T07:00:35.746066Z] [debug] [pid:73306] loaded 7144 needles[0m
[37m[2024-05-28T07:00:35.904118Z] [debug] [pid:73306] 73306: channel_out 16, channel_in 15[0m
[37m[2024-05-28T07:00:35.953311Z] [debug] [pid:73980] 73980: cmdpipe 14, rsppipe 17[0m
[37m[2024-05-28T07:00:35.953591Z] [debug] [pid:73980] started mgmt loop with pid 73980[0m
[37m[2024-05-28T07:00:36.012670Z] [debug] [pid:73980] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libvpx-vp9 -crf 35 -b:v 1500k -cpu-used 1 'video.webm'[0m
[37m[2024-05-28T07:00:36.080751Z] [debug] [pid:73980] qemu version detected: 7.1.0[0m
[37m[2024-05-28T07:00:36.082244Z] [debug] [pid:73980] running `/usr/bin/chattr +C /var/lib/openqa/pool/24/raid`[0m
[37m[2024-05-28T07:00:36.093328Z] [debug] [pid:73980] Command `/usr/bin/chattr +C /var/lib/openqa/pool/24/raid` terminated with 1
  /usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/24/raid[0m
[37m[2024-05-28T07:00:36.093432Z] [debug] [pid:73980] Configuring storage controllers and block devices[0m
[37m[2024-05-28T07:00:36.093968Z] [debug] [pid:73980] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/24/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso`[0m
[37m[2024-05-28T07:00:36.131937Z] [debug] [pid:73980] Initializing block device images[0m
[37m[2024-05-28T07:00:36.132127Z] [debug] [pid:73980] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/24/raid/hd0 20G`[0m
[37m[2024-05-28T07:00:36.166663Z] [debug] [pid:73980] Formatting '/var/lib/openqa/pool/24/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:00:36.166806Z] [debug] [pid:73980] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /var/lib/openqa/pool/24/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso /var/lib/openqa/pool/24/raid/cd0-overlay0 4497342464`[0m
[37m[2024-05-28T07:00:36.205591Z] [debug] [pid:73980] Formatting '/var/lib/openqa/pool/24/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/24/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20240527-Media.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:00:36.205669Z] [debug] [pid:73980] init_blockdev_images: Finished creating block devices[0m
[37m[2024-05-28T07:00:36.206593Z] [debug] [pid:73980] starting: /usr/bin/qemu-system-x86_64 -device VGA,edid=on,xres=1024,yres=768 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.fdtypeA=none -m 1536 -cpu host -netdev user,id=qanet0,hostfwd=tcp::39114-:39114 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot once=d -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :114,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/var/lib/openqa/pool/24/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/24/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on,discard=unmap -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0[0m
[37m[2024-05-28T07:00:36.212308Z] [debug] [pid:73980] Waiting for 0 attempts[0m
[37m[2024-05-28T07:00:37.212819Z] [debug] [pid:73980] Waiting for 1 attempts[0m
[37m[2024-05-28T07:00:38.213148Z] [debug] [pid:73980] Finished after 2 attempts[0m
[37m[2024-05-28T07:00:38.226498Z] [debug] [pid:73980] Establishing VNC connection to localhost:6014[0m
[37m[2024-05-28T07:00:38.228788Z] [debug] [pid:73980] pointer type 0 0 640 480 -257[0m
[37m[2024-05-28T07:00:38.228859Z] [debug] [pid:73980] led state 0 1 1 -261[0m
[37m[2024-05-28T07:00:38.283491Z] [debug] [pid:73980] Start CPU[0m
[37m[2024-05-28T07:00:38.283741Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"45200","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":227010,"seconds":1716879638}}[0m
[37m[2024-05-28T07:00:38.283845Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"45200","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":227960,"seconds":1716879638}}[0m
[37m[2024-05-28T07:00:38.283934Z] [debug] [pid:73980] EVENT {"event":"RESUME","timestamp":{"microseconds":283743,"seconds":1716879638}}[0m
GOT GO

[37m[2024-05-28T07:00:38.289653Z] [debug] [pid:73980] QEMU: QEMU emulator version 7.1.0 (SUSE Linux Enterprise 15)[0m
[37m[2024-05-28T07:00:38.289711Z] [debug] [pid:73980] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers[0m
[37m[2024-05-28T07:00:38.292804Z] [debug] [pid:73784] Snapshots are supported[0m
[1;34m[2024-05-28T07:00:38.293960Z] [debug] [pid:73784] ||| starting prepare_profile tests/autoyast/prepare_profile.pm[0m
[2024-05-28T07:00:38.295192Z] [debug] [pid:73784] tests/autoyast/prepare_profile.pm:22 called testapi::get_test_data
[2024-05-28T07:00:38.295408Z] [debug] [pid:73784] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_firstboot.xml")
[2024-05-28T07:00:38.296586Z] [debug] [pid:73784] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:859 called testapi::get_test_data
[2024-05-28T07:00:38.296673Z] [debug] [pid:73784] <<< testapi::get_test_data(path="opensuse/data/autoyast_opensuse/autoyast_firstboot.xml")
[2024-05-28T07:00:38.297026Z] [debug] [pid:73784] tests/autoyast/prepare_profile.pm:27 called autoyast::prepare_ay_file -> lib/autoyast.pm:874 called autoyast::upload_profile -> lib/autoyast.pm:742 called testapi::save_tmp_file
[2024-05-28T07:00:38.297106Z] [debug] [pid:73784] <<< testapi::save_tmp_file(path="autoyast_opensuse/autoyast_firstboot.xml")
[1;34m[2024-05-28T07:00:38.299286Z] [debug] [pid:73784] ||| finished prepare_profile autoyast (runtime: 0 s)[0m
[1;34m[2024-05-28T07:00:38.352557Z] [debug] [pid:73784] ||| starting bootloader_start tests/installation/bootloader_start.pm[0m
[2024-05-28T07:00:38.353180Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:83 called testapi::record_info
[2024-05-28T07:00:38.353285Z] [debug] [pid:73784] <<< testapi::record_info(title="bootloader", output="", result="ok")
[2024-05-28T07:00:38.353520Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:330 called testapi::assert_screen
[2024-05-28T07:00:38.353597Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch="inst-bootmenu", timeout=30)
[37m[2024-05-28T07:00:39.427301Z] [debug] [pid:73980] no match: 29.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
Input #0, image2pipe, from 'pipe:':
  Duration: N/A, bitrate: N/A
  Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn, 24 tbc
Stream mapping:
  Stream #0:0 -> #0:0 (ppm (native) -> vp9 (libvpx-vp9))
[libvpx-vp9 @ 0x55cb896ee900] v1.11.0
Output #0, webm, to 'video.webm':
  Metadata:
    encoder         : Lavf58.76.100
  Stream #0:0: Video: vp9, yuv420p(tv, progressive), 1024x768, q=2-31, 1500 kb/s, 24 fps, 1k tbn
    Metadata:
      encoder         : Lavc58.134.100 libvpx-vp9
    Side data:
      cpb: bitrate max/min/avg: 0/0/0 buffer size: 0 vbv_delay: N/A
[37m[2024-05-28T07:00:40.345401Z] [debug] [pid:73980] no match: 28.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[37m[2024-05-28T07:00:41.344976Z] [debug] [pid:73980] no match: 27.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[37m[2024-05-28T07:00:42.352490Z] [debug] [pid:73980] no match: 26.0s, best candidate: bootloader-grub2-alp-selfinstall-20230327 (0.00)[0m
[32m[2024-05-28T07:00:43.839178Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found bootmenu-Slowroll-20240109, similarity 1.00 @ 0/0[0m
[2024-05-28T07:00:43.840020Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:00:43.840141Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=0)
[37m[2024-05-28T07:00:44.649350Z] [debug] [pid:73980] no match: -0.5s, best candidate: inst-oninstallation-20191209 (0.45)[0m
[32m[2024-05-28T07:00:44.717875Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=inst-oninstallation timed out after 0 (check_screen)[0m
[2024-05-28T07:00:44.732702Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:00:44.732819Z] [debug] [pid:73784] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2024-05-28T07:00:44.733516Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:00:44.733594Z] [debug] [pid:73784] <<< testapi::send_key(key="down", wait_screen_change=0)
[32m[2024-05-28T07:00:45.183940Z] [debug] [pid:73784] >>> testapi::wait_screen_change: screen change seen after 0.177424192428589 seconds (similarity: 25.510891502542)[0m
[2024-05-28T07:00:45.184125Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:43 called bootloader_setup::select_bootmenu_option -> lib/bootloader_setup.pm:348 called testapi::send_key_until_needlematch
[2024-05-28T07:00:45.184240Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch="inst-oninstallation", timeout=5)
[32m[2024-05-28T07:00:45.360302Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found inst-oninstallation-20191209, similarity 1.00 @ 246/192[0m
[2024-05-28T07:00:45.360731Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:53 called bootloader_setup::bootmenu_default_params -> lib/bootloader_setup.pm:623 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T07:00:45.360886Z] [debug] [pid:73784] <<< testapi::type_string(string="  Y2DEBUG=1 vga=791 video=1024x768 plymouth.ignore-serial-consoles console=ttyS0 console=tty linuxrc.log=/dev/ttyS0 linuxrc.core=/dev/ttyS0 linuxrc.debug=4,trace extend=libyui-rest-api YUI_HTTP_PORT=39114 YUI_HTTP_REMOTE=1 YUI_REUSE_PORT=1 reboot_timeout=0  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:03:16.979748Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:56 called bootloader_setup::specific_bootmenu_params -> lib/bootloader_setup.pm:913 called bootloader_setup::type_boot_parameters -> lib/bootloader_setup.pm:1592 called testapi::type_string
[2024-05-28T07:03:16.979977Z] [debug] [pid:73784] <<< testapi::type_string(string="  ifcfg=*=dhcp SetHostname=0 autoyast=http://10.0.2.2:20243/4aPEXtdmIuNlGqc0/files/autoyast_opensuse/autoyast_firstboot.xml kernel.softlockup_panic=1  ", max_interval=4, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:04:41.377509Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:68 called testapi::send_key
[2024-05-28T07:04:41.377644Z] [debug] [pid:73784] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:04:41.645548Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::parse_bootparams_in_serial -> lib/bootloader_setup.pm:1507 called testapi::wait_serial
[2024-05-28T07:04:41.645809Z] [debug] [pid:73784] <<< testapi::wait_serial(regexp=qr/command line:.*\[/msi, buffer_size=undef, timeout=90, expect_not_found=0, no_regex=0, record_output=undef, quiet=undef)
[32m[2024-05-28T07:04:43.691590Z] [debug] [pid:73784] >>> testapi::wait_serial: (?^msi:command line:.*\[): ok[0m
[2024-05-28T07:04:43.691842Z] [debug] [pid:73784] tests/installation/bootloader_start.pm:84 called bootloader::run -> tests/installation/bootloader.pm:71 called bootloader_setup::compare_bootparams -> lib/bootloader_setup.pm:1530 called testapi::record_info
[2024-05-28T07:04:43.692025Z] [debug] [pid:73784] <<< testapi::record_info(title="params ok", output="Bootloader parameters are typed correctly.\nVerified parameters:\nY2DEBUG=1\nvga=791\nvideo=1024x768\nplymouth.ignore-serial-consoles\nconsole=ttyS0\nconsole=tty\nlinuxrc.log=/dev/ttyS0\nlinuxrc.core=/dev/ttyS0\nlinuxrc.debug=4,trace\nextend=libyui-rest-api\nYUI_HTTP_PORT=39114\nYUI_HTTP_REMOTE=1\nYUI_REUSE_PORT=1\nreboot_timeout=0\nifcfg=*=dhcp\nSetHostname=0\nautoyast=http://10.0.2.2:20243/4aPEXtdmIuNlGqc0/files/autoyast_opensuse/autoyast_firstboot.xml\nkernel.softlockup_panic=1", result="ok")
[1;34m[2024-05-28T07:04:43.695841Z] [debug] [pid:73784] ||| finished bootloader_start installation (runtime: 245 s)[0m
[1;34m[2024-05-28T07:04:43.696930Z] [debug] [pid:73784] ||| starting installation tests/autoyast/installation.pm[0m
[2024-05-28T07:04:43.710608Z] [debug] [pid:73784] tests/autoyast/installation.pm:109 called autoyast::test_ayp_url -> lib/autoyast.pm:800 called testapi::record_info
[2024-05-28T07:04:43.710791Z] [debug] [pid:73784] <<< testapi::record_info(title="ayp url ok", output="Autoyast profile url http://localhost:20243/4aPEXtdmIuNlGqc0/files/autoyast_opensuse/autoyast_firstboot.xml is reachable from the worker", result="ok")
[2024-05-28T07:04:43.711192Z] [debug] [pid:73784] tests/autoyast/installation.pm:169 called testapi::check_screen
[2024-05-28T07:04:43.711343Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:04:47.212379Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.50 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:47.212479Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[37m[2024-05-28T07:04:47.212971Z] [debug] [pid:73980] pointer type 1 0 1024 768 -257[0m
[31m[2024-05-28T07:04:49.050896Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:49.050981Z] [debug] [pid:73980] no match: 46.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:04:50.889356Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:50.889449Z] [debug] [pid:73980] no match: 44.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:04:52.913726Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.02 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:52.913827Z] [debug] [pid:73980] no match: 42.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:04:58.435402Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.52 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:04:58.435499Z] [debug] [pid:73980] no match: 40.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:04:58.437937Z] [debug] [pid:73980] no change: 35.2s[0m
[31m[2024-05-28T07:05:03.989933Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.55 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:03.990025Z] [debug] [pid:73980] no match: 35.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:05:06.010198Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.01 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:06.010286Z] [debug] [pid:73980] no match: 29.7s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:08.006787Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.99 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:08.006874Z] [debug] [pid:73980] no match: 27.6s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:13.486259Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.48 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:13.486354Z] [debug] [pid:73980] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:19.161627Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.67 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:19.161721Z] [debug] [pid:73980] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:21.325686Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:21.325778Z] [debug] [pid:73980] no match: 14.5s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:23.401635Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.07 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:23.401725Z] [debug] [pid:73980] no match: 12.3s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:28.948605Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.54 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:28.948692Z] [debug] [pid:73980] no match: 10.3s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:30.960213Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.01 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:30.960307Z] [debug] [pid:73980] no match: 4.7s, best candidate: consoletest_finish-gnome-20150915 (0.05)[0m
[31m[2024-05-28T07:05:33.018066Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.05 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:33.018154Z] [debug] [pid:73980] no match: 2.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:05:39.006305Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.98 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:39.006393Z] [debug] [pid:73980] no match: 0.6s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[31m[2024-05-28T07:05:44.605500Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.59 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:44.605583Z] [debug] [pid:73980] no match: -5.3s, best candidate: consoletest_finish-gnome-20150915 (0.08)[0m
[32m[2024-05-28T07:05:44.779725Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:05:44.797356Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:05:44.797513Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:05:47.510949Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.71 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:47.511041Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:05:49.321835Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:49.321933Z] [debug] [pid:73980] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:05:54.792525Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.47 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:05:54.792614Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:00.129015Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:00.129111Z] [debug] [pid:73980] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:02.018506Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.88 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:02.018609Z] [debug] [pid:73980] no match: 34.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:03.814464Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:03.814550Z] [debug] [pid:73980] no match: 32.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:09.099510Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:09.099593Z] [debug] [pid:73980] no match: 30.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:14.439200Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:14.439292Z] [debug] [pid:73980] no match: 25.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:19.843570Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.40 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:19.843669Z] [debug] [pid:73980] no match: 20.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:21.693784Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:21.693875Z] [debug] [pid:73980] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:23.560272Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:23.560369Z] [debug] [pid:73980] no match: 13.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:25.561704Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.00 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:25.561803Z] [debug] [pid:73980] no match: 11.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:27.375405Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:27.375497Z] [debug] [pid:73980] no match: 9.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:29.200507Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:29.200598Z] [debug] [pid:73980] no match: 7.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:34.599141Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.39 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:34.599222Z] [debug] [pid:73980] no match: 5.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:39.924887Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.32 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:39.924984Z] [debug] [pid:73980] no match: 0.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:45.290280Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:45.290362Z] [debug] [pid:73980] no match: -5.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:06:45.444469Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:06:45.461091Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:06:45.461246Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:06:48.154568Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.69 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:48.154651Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:49.946020Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:49.946109Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:06:55.167899Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:06:55.167986Z] [debug] [pid:73980] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:00.414258Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:00.414347Z] [debug] [pid:73980] no match: 40.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:05.741355Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.32 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:05.741438Z] [debug] [pid:73980] no match: 35.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:07.594370Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:07.594455Z] [debug] [pid:73980] no match: 29.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:09.422714Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:09.422800Z] [debug] [pid:73980] no match: 27.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:11.229304Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:11.229386Z] [debug] [pid:73980] no match: 26.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:13.026727Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:13.026813Z] [debug] [pid:73980] no match: 24.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:14.813554Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:14.813646Z] [debug] [pid:73980] no match: 22.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:20.018705Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:20.018795Z] [debug] [pid:73980] no match: 20.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:25.226970Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.20 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:25.227057Z] [debug] [pid:73980] no match: 15.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:30.447904Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:30.447989Z] [debug] [pid:73980] no match: 10.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:35.727348Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:35.727439Z] [debug] [pid:73980] no match: 5.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:40.975246Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:40.975335Z] [debug] [pid:73980] no match: -0.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:07:41.069253Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:07:41.084866Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:07:41.085021Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:07:43.815079Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.73 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:43.815162Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:45.643136Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:45.643228Z] [debug] [pid:73980] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:51.038659Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.39 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:51.038746Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:56.426193Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:56.426295Z] [debug] [pid:73980] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:07:58.300596Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.87 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:07:58.300726Z] [debug] [pid:73980] no match: 34.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:00.140159Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:00.140249Z] [debug] [pid:73980] no match: 32.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:05.408316Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:05.408409Z] [debug] [pid:73980] no match: 30.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:10.588582Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.18 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:10.588670Z] [debug] [pid:73980] no match: 25.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:15.977314Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:15.977412Z] [debug] [pid:73980] no match: 20.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:21.413895Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.43 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:21.413988Z] [debug] [pid:73980] no match: 15.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:23.270657Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:23.270756Z] [debug] [pid:73980] no match: 9.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:25.132442Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:25.132532Z] [debug] [pid:73980] no match: 7.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:30.545480Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.41 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:30.545570Z] [debug] [pid:73980] no match: 5.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:35.944073Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.39 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:35.944164Z] [debug] [pid:73980] no match: 0.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:41.255592Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:41.255686Z] [debug] [pid:73980] no match: -4.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:08:41.348357Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:08:41.363383Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:08:41.363528Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:08:44.052992Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.69 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:44.053079Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:45.853265Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:45.853469Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:51.217126Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:51.217223Z] [debug] [pid:73980] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:56.496946Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:56.497037Z] [debug] [pid:73980] no match: 40.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:08:58.317142Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:08:58.317234Z] [debug] [pid:73980] no match: 34.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:00.111326Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:00.111420Z] [debug] [pid:73980] no match: 33.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:09:00.113962Z] [debug] [pid:73980] no change: 31.2s[0m
[31m[2024-05-28T07:09:01.935072Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:01.935167Z] [debug] [pid:73980] no match: 31.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:03.736911Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:03.737014Z] [debug] [pid:73980] no match: 29.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:05.547504Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:05.547603Z] [debug] [pid:73980] no match: 27.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:11.055650Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.50 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:11.055764Z] [debug] [pid:73980] no match: 25.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:16.460194Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.40 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:16.460293Z] [debug] [pid:73980] no match: 20.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:18.263569Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:18.263654Z] [debug] [pid:73980] no match: 14.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:20.068268Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:20.068372Z] [debug] [pid:73980] no match: 13.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:21.894974Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:21.895072Z] [debug] [pid:73980] no match: 11.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:23.678210Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:23.678310Z] [debug] [pid:73980] no match: 9.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:25.465836Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:25.465938Z] [debug] [pid:73980] no match: 7.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:30.652234Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.18 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:30.652331Z] [debug] [pid:73980] no match: 5.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:35.902967Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.25 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:35.903068Z] [debug] [pid:73980] no match: 0.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:41.186109Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:41.186199Z] [debug] [pid:73980] no match: -4.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:09:41.288390Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:09:41.303255Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:09:41.303428Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:09:43.994207Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.69 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:43.994300Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:45.803588Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:45.803670Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:51.248395Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.44 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:51.248491Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:56.660498Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.41 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:56.660591Z] [debug] [pid:73980] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:09:58.519683Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:09:58.519776Z] [debug] [pid:73980] no match: 34.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:00.343804Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:00.343888Z] [debug] [pid:73980] no match: 32.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:05.860580Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.51 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:05.860678Z] [debug] [pid:73980] no match: 30.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:11.268735Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.40 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:11.268825Z] [debug] [pid:73980] no match: 25.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:16.732203Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.46 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:16.732289Z] [debug] [pid:73980] no match: 20.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:18.545474Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:18.545571Z] [debug] [pid:73980] no match: 14.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:20.380113Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:20.380209Z] [debug] [pid:73980] no match: 12.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:25.657145Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:25.657243Z] [debug] [pid:73980] no match: 10.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:30.929631Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:30.929718Z] [debug] [pid:73980] no match: 5.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:36.142454Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:36.142542Z] [debug] [pid:73980] no match: 0.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:41.314075Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:41.314158Z] [debug] [pid:73980] no match: -4.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:10:41.410359Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:10:41.424817Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:10:41.424961Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:10:44.093997Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.67 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:44.094079Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:45.880330Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:45.880414Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:10:51.181181Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:51.181265Z] [debug] [pid:73980] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:10:51.181557Z] [debug] [pid:73980] considering VNC stalled, no update for 5.30 seconds[0m
[37m[2024-05-28T07:10:51.183493Z] [debug] [pid:73980] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T07:10:51.183586Z] [debug] [pid:73980] led state 0 1 1 -261[0m
[37m[2024-05-28T07:10:51.185564Z] [debug] [pid:73980] no change: 40.2s[0m
[31m[2024-05-28T07:10:56.460193Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:56.460276Z] [debug] [pid:73980] no match: 40.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:10:56.461640Z] [debug] [pid:73980] considering VNC stalled, no update for 5.28 seconds[0m
[37m[2024-05-28T07:10:56.463586Z] [debug] [pid:73980] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T07:10:56.463680Z] [debug] [pid:73980] led state 0 1 1 -261[0m
[37m[2024-05-28T07:10:56.465702Z] [debug] [pid:73980] no change: 34.9s[0m
[31m[2024-05-28T07:10:58.318378Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:10:58.318462Z] [debug] [pid:73980] no match: 34.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:10:58.321018Z] [debug] [pid:73980] no change: 33.1s[0m
[31m[2024-05-28T07:11:00.154382Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:00.154464Z] [debug] [pid:73980] no match: 33.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:11:00.159494Z] [debug] [pid:73980] no change: 31.2s[0m
[31m[2024-05-28T07:11:02.024197Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:02.024281Z] [debug] [pid:73980] no match: 31.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:11:02.026849Z] [debug] [pid:73980] no change: 29.3s[0m
[31m[2024-05-28T07:11:03.871090Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:03.871175Z] [debug] [pid:73980] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:05.736396Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:05.736497Z] [debug] [pid:73980] no match: 27.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:11.156589Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.42 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:11.156672Z] [debug] [pid:73980] no match: 25.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:16.499925Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:16.500033Z] [debug] [pid:73980] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:18.337015Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:18.337117Z] [debug] [pid:73980] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:20.195187Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:20.195278Z] [debug] [pid:73980] no match: 13.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:22.052713Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:22.052814Z] [debug] [pid:73980] no match: 11.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:11:22.055324Z] [debug] [pid:73980] no change: 9.3s[0m
[31m[2024-05-28T07:11:23.880942Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:23.881041Z] [debug] [pid:73980] no match: 9.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:25.681487Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:25.681583Z] [debug] [pid:73980] no match: 7.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:30.958643Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:30.958737Z] [debug] [pid:73980] no match: 5.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:36.239320Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:36.239410Z] [debug] [pid:73980] no match: 0.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:41.484921Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:41.485017Z] [debug] [pid:73980] no match: -4.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:11:41.582295Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:11:41.598840Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:11:41.598999Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:11:44.299894Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.70 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:44.299989Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:46.091096Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:46.091190Z] [debug] [pid:73980] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:51.336449Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:51.336548Z] [debug] [pid:73980] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:56.727637Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.39 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:56.727737Z] [debug] [pid:73980] no match: 40.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:11:58.564178Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:11:58.564275Z] [debug] [pid:73980] no match: 34.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:00.424521Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:00.424618Z] [debug] [pid:73980] no match: 33.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:02.249927Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:02.250023Z] [debug] [pid:73980] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:12:02.252610Z] [debug] [pid:73980] no change: 29.3s[0m
[31m[2024-05-28T07:12:04.174854Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.92 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:04.174949Z] [debug] [pid:73980] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:05.998868Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:05.998967Z] [debug] [pid:73980] no match: 27.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:11.257353Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.25 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:11.257446Z] [debug] [pid:73980] no match: 25.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:16.483592Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:16.483680Z] [debug] [pid:73980] no match: 20.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:21.716915Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:21.717003Z] [debug] [pid:73980] no match: 15.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:23.529020Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:23.529105Z] [debug] [pid:73980] no match: 9.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:25.473972Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.94 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:25.474069Z] [debug] [pid:73980] no match: 8.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:27.319678Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:27.319763Z] [debug] [pid:73980] no match: 6.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:29.186434Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:29.186522Z] [debug] [pid:73980] no match: 4.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:12:29.189008Z] [debug] [pid:73980] no change: 2.4s[0m
[31m[2024-05-28T07:12:31.154797Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.97 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:31.154904Z] [debug] [pid:73980] no match: 2.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:36.462728Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:36.462819Z] [debug] [pid:73980] no match: 0.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:41.660596Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.19 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:41.660680Z] [debug] [pid:73980] no match: -4.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:12:41.761782Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:12:41.776123Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:12:41.776283Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:12:44.462181Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.68 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:44.462267Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:46.306979Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:46.307074Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:51.767558Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.46 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:51.767639Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:57.183682Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.41 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:57.183771Z] [debug] [pid:73980] no match: 40.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:12:59.002861Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:12:59.002950Z] [debug] [pid:73980] no match: 34.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:00.863842Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:00.863932Z] [debug] [pid:73980] no match: 32.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:06.035459Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.17 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:06.035561Z] [debug] [pid:73980] no match: 30.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:11.216693Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.18 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:11.216784Z] [debug] [pid:73980] no match: 25.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:13:11.222283Z] [debug] [pid:73980] no change: 20.5s[0m
[31m[2024-05-28T07:13:16.493090Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:16.493199Z] [debug] [pid:73980] no match: 20.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:21.682015Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.18 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:21.682103Z] [debug] [pid:73980] no match: 15.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:26.959161Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:26.959263Z] [debug] [pid:73980] no match: 10.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:28.764329Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:28.764419Z] [debug] [pid:73980] no match: 4.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:30.553646Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:30.553734Z] [debug] [pid:73980] no match: 3.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:32.340314Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:32.340398Z] [debug] [pid:73980] no match: 1.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:37.520070Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.18 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:37.520177Z] [debug] [pid:73980] no match: -0.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:13:37.621640Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:13:37.636607Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:13:37.636770Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:13:40.306251Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.67 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:40.306358Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:42.093157Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.78 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:42.093248Z] [debug] [pid:73980] no match: 47.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:47.322048Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.22 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:47.322141Z] [debug] [pid:73980] no match: 45.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:52.533199Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.21 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:52.533297Z] [debug] [pid:73980] no match: 40.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:57.819073Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.28 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:57.819168Z] [debug] [pid:73980] no match: 35.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:13:59.614968Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:13:59.615071Z] [debug] [pid:73980] no match: 29.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:01.405983Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:01.406076Z] [debug] [pid:73980] no match: 28.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:03.226395Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:03.226485Z] [debug] [pid:73980] no match: 26.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:14:03.228908Z] [debug] [pid:73980] no change: 24.4s[0m
[31m[2024-05-28T07:14:05.017196Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.79 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:05.017282Z] [debug] [pid:73980] no match: 24.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:06.855246Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:06.855341Z] [debug] [pid:73980] no match: 22.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:12.288238Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.43 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:12.288334Z] [debug] [pid:73980] no match: 20.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:17.827288Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.53 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:17.827374Z] [debug] [pid:73980] no match: 15.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:19.696606Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.86 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:19.696703Z] [debug] [pid:73980] no match: 9.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:21.556480Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:21.556574Z] [debug] [pid:73980] no match: 7.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:23.458480Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.90 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:23.458572Z] [debug] [pid:73980] no match: 6.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:25.264472Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:25.264558Z] [debug] [pid:73980] no match: 4.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:27.070080Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:27.070171Z] [debug] [pid:73980] no match: 2.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:32.361975Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:32.362075Z] [debug] [pid:73980] no match: 0.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:37.595921Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.23 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:37.596017Z] [debug] [pid:73980] no match: -4.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:14:37.701016Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:14:37.719847Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:14:37.720078Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:14:40.442842Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.72 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:40.442943Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:42.295190Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.85 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:42.295288Z] [debug] [pid:73980] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:47.601065Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.30 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:47.601165Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:52.943008Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.34 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:52.943092Z] [debug] [pid:73980] no match: 40.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:54.774335Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:54.774426Z] [debug] [pid:73980] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:56.583162Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:56.583270Z] [debug] [pid:73980] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:14:58.397508Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:14:58.397599Z] [debug] [pid:73980] no match: 31.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:00.245691Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:00.245785Z] [debug] [pid:73980] no match: 29.3s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:02.064854Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:02.064959Z] [debug] [pid:73980] no match: 27.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:07.422830Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:07.422924Z] [debug] [pid:73980] no match: 25.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:12.807271Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.38 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:12.807357Z] [debug] [pid:73980] no match: 20.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:14.626362Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.81 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:14.626460Z] [debug] [pid:73980] no match: 14.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:16.454224Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:16.454322Z] [debug] [pid:73980] no match: 13.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:18.257329Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:18.257426Z] [debug] [pid:73980] no match: 11.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:20.076656Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:20.076761Z] [debug] [pid:73980] no match: 9.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:21.914661Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:21.914749Z] [debug] [pid:73980] no match: 7.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:27.178102Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.26 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:27.178214Z] [debug] [pid:73980] no match: 5.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:15:27.179656Z] [debug] [pid:73980] considering VNC stalled, no update for 7.10 seconds[0m
[37m[2024-05-28T07:15:27.183784Z] [debug] [pid:73980] no change: 0.5s[0m
[31m[2024-05-28T07:15:32.420804Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.24 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:32.420893Z] [debug] [pid:73980] no match: 0.5s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:15:32.421009Z] [debug] [pid:73980] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T07:15:32.421069Z] [debug] [pid:73980] led state 0 1 1 -261[0m
[31m[2024-05-28T07:15:37.693399Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.27 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:37.693480Z] [debug] [pid:73980] no match: -4.8s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:15:37.800062Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,bios-boot,import-untrusted-gpg-key,linuxrc-install-fail,manual-intervention,nonexisting-package,nvidia-validation-failed,opensuse-welcome,package-notification,reboot-after-installation,scc-invalid-url,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:15:37.815336Z] [debug] [pid:73784] tests/autoyast/installation.pm:179 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:15:37.815489Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:15:40.523697Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.71 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:40.523804Z] [debug] [pid:73980] no match: 49.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:42.351895Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.82 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:42.351988Z] [debug] [pid:73980] no match: 47.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:47.648236Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.29 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:47.648322Z] [debug] [pid:73980] no match: 45.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:53.013915Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.36 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:53.014024Z] [debug] [pid:73980] no match: 40.1s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:54.857802Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:54.857899Z] [debug] [pid:73980] no match: 34.7s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:15:56.741273Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.88 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:56.741363Z] [debug] [pid:73980] no match: 32.9s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:15:56.743920Z] [debug] [pid:73980] no change: 31.0s[0m
[31m[2024-05-28T07:15:58.575727Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.83 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:15:58.575812Z] [debug] [pid:73980] no match: 31.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:15:58.578310Z] [debug] [pid:73980] no change: 29.2s[0m
[31m[2024-05-28T07:16:00.378030Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.80 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:00.378131Z] [debug] [pid:73980] no match: 29.2s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:16:00.380752Z] [debug] [pid:73980] no change: 27.4s[0m
[31m[2024-05-28T07:16:02.357395Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.98 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:02.357479Z] [debug] [pid:73980] no match: 27.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:16:07.805474Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.44 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:07.805558Z] [debug] [pid:73980] no match: 25.4s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:16:07.806701Z] [debug] [pid:73980] considering VNC stalled, no update for 5.45 seconds[0m
[37m[2024-05-28T07:16:07.810387Z] [debug] [pid:73980] no change: 20.0s[0m
[31m[2024-05-28T07:16:13.139079Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.33 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:13.139179Z] [debug] [pid:73980] no match: 20.0s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[37m[2024-05-28T07:16:13.139312Z] [debug] [pid:73980] pointer type 1 0 1024 768 -257[0m
[37m[2024-05-28T07:16:13.139402Z] [debug] [pid:73980] led state 0 1 1 -261[0m
[37m[2024-05-28T07:16:13.143020Z] [debug] [pid:73980] no change: 14.6s[0m
[31m[2024-05-28T07:16:14.987891Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.84 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:14.987981Z] [debug] [pid:73980] no match: 14.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[31m[2024-05-28T07:16:17.149280Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.16 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:17.149382Z] [debug] [pid:73980] no match: 12.8s, best candidate: consoletest_finish-gnome-20191211 (0.22)[0m
[31m[2024-05-28T07:16:22.648215Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.49 seconds for 149 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:22.648312Z] [debug] [pid:73980] no match: 10.6s, best candidate: consoletest_finish-gnome-20150915 (0.00)[0m
[32m[2024-05-28T07:16:28.163831Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147[0m
[2024-05-28T07:16:28.165115Z] [debug] [pid:73784] tests/autoyast/installation.pm:181 called testapi::send_key
[2024-05-28T07:16:28.165241Z] [debug] [pid:73784] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:16:28.433640Z] [debug] [pid:73784] tests/autoyast/installation.pm:345 called testapi::check_screen
[2024-05-28T07:16:28.433869Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "bios-boot",
    "nonexisting-package",
    "reboot-after-installation",
    "linuxrc-install-fail",
    "scc-invalid-url",
    "warning-pop-up",
    "autoyast-boot",
    "package-notification",
    "nvidia-validation-failed",
    "import-untrusted-gpg-key",
    "autoyast-error",
    "manual-intervention",
    "opensuse-welcome"
  ], timeout=50)
[32m[2024-05-28T07:16:31.197673Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147[0m
[2024-05-28T07:16:31.198294Z] [debug] [pid:73784] tests/autoyast/installation.pm:362 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:16:31.198427Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "reboot-after-installation",
    "autoyast-postinstall-error",
    "autoyast-boot",
    "unreachable-repo",
    "warning-pop-up",
    "inst-bootmenu",
    "lang_and_keyboard",
    "encrypted-disk-password-prompt",
    "autoyast-error",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:16:34.287757Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.09 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:34.287857Z] [debug] [pid:73980] no match: 49.9s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:36.704817Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.41 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:36.704914Z] [debug] [pid:73980] no match: 46.9s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[37m[2024-05-28T07:16:36.710028Z] [debug] [pid:73980] no change: 44.4s[0m
[31m[2024-05-28T07:16:39.111193Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.40 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:39.111296Z] [debug] [pid:73980] no match: 44.4s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:41.526884Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.41 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:41.526986Z] [debug] [pid:73980] no match: 42.0s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:43.980991Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.45 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:43.981093Z] [debug] [pid:73980] no match: 39.6s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:46.329466Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.34 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:46.329557Z] [debug] [pid:73980] no match: 37.2s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:48.745373Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.41 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:48.745485Z] [debug] [pid:73980] no match: 34.8s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:16:50.672149Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.92 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:50.672252Z] [debug] [pid:73980] no match: 32.4s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:16:57.310125Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 6.63 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:57.310228Z] [debug] [pid:73980] no match: 30.5s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:16:59.269093Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.95 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:16:59.269191Z] [debug] [pid:73980] no match: 23.8s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[37m[2024-05-28T07:16:59.274217Z] [debug] [pid:73980] no change: 21.9s[0m
[31m[2024-05-28T07:17:01.195694Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.92 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:01.195793Z] [debug] [pid:73980] no match: 21.9s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:07.837227Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 6.64 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:07.837332Z] [debug] [pid:73980] no match: 20.0s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:09.747029Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.91 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:09.747126Z] [debug] [pid:73980] no match: 13.3s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[37m[2024-05-28T07:17:09.752029Z] [debug] [pid:73980] no change: 11.4s[0m
[31m[2024-05-28T07:17:11.696073Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.94 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:11.696174Z] [debug] [pid:73980] no match: 11.4s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[37m[2024-05-28T07:17:11.698839Z] [debug] [pid:73980] no change: 9.5s[0m
[31m[2024-05-28T07:17:13.646612Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.95 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:13.646715Z] [debug] [pid:73980] no match: 9.5s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:15.601395Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.95 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:15.601486Z] [debug] [pid:73980] no match: 7.5s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:22.130501Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 6.53 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:22.130607Z] [debug] [pid:73980] no match: 5.5s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:28.720946Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 6.59 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:28.721056Z] [debug] [pid:73980] no match: -1.0s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[32m[2024-05-28T07:17:28.886895Z] [debug] [pid:73784] >>> testapi::_check_backend_response: match=autoyast-boot,autoyast-error,autoyast-postinstall-error,encrypted-disk-password-prompt,inst-bootmenu,lang_and_keyboard,opensuse-welcome,reboot-after-installation,unreachable-repo,warning-pop-up timed out after 50 (check_screen)[0m
[2024-05-28T07:17:28.903638Z] [debug] [pid:73784] tests/autoyast/installation.pm:362 called installation::verify_timeout_and_check_screen -> tests/autoyast/installation.pm:103 called testapi::check_screen
[2024-05-28T07:17:28.903785Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "reboot-after-installation",
    "autoyast-postinstall-error",
    "autoyast-boot",
    "unreachable-repo",
    "warning-pop-up",
    "inst-bootmenu",
    "lang_and_keyboard",
    "encrypted-disk-password-prompt",
    "autoyast-error",
    "opensuse-welcome"
  ], timeout=50)
[31m[2024-05-28T07:17:31.930455Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 3.02 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:31.930551Z] [debug] [pid:73980] no match: 49.9s, best candidate: yast2_firstboot-lang_and_keyboard-20210610 (0.18)[0m
[31m[2024-05-28T07:17:34.240873Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.30 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:34.240958Z] [debug] [pid:73980] no match: 46.9s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:17:36.707404Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.46 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:36.707504Z] [debug] [pid:73980] no match: 44.6s, best candidate: boot_encrypt-encrypted-disk-password-prompt-20221029 (0.29)[0m
[31m[2024-05-28T07:17:38.693526Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.98 seconds for 182 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:17:38.693629Z] [debug] [pid:73980] no match: 42.1s, best candidate: yast2_firstboot-lang_and_keyboard-20230407 (0.18)[0m
[32m[2024-05-28T07:17:45.676616Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found yast2_firstboot-lang_and_keyboard-20230407, similarity 1.00 @ 454/238[0m
[1;34m[2024-05-28T07:17:45.729818Z] [debug] [pid:73784] ||| finished installation autoyast (runtime: 782 s)[0m
[1;34m[2024-05-28T07:17:45.737352Z] [debug] [pid:73784] ||| starting firstboot_language_and_keyboard tests/installation/yast_firstboot/firstboot_language_and_keyboard.pm[0m
[1;34m[2024-05-28T07:17:52.811895Z] [debug] [pid:73784] ||| finished firstboot_language_and_keyboard installation/yast_firstboot (runtime: 7 s)[0m
[1;34m[2024-05-28T07:17:52.812734Z] [debug] [pid:73784] ||| starting firstboot_welcome tests/installation/yast_firstboot/firstboot_welcome.pm[0m
[1;34m[2024-05-28T07:17:57.875649Z] [debug] [pid:73784] ||| finished firstboot_welcome installation/yast_firstboot (runtime: 5 s)[0m
[1;34m[2024-05-28T07:17:57.876506Z] [debug] [pid:73784] ||| starting firstboot_license_agreement tests/installation/yast_firstboot/firstboot_license_agreement.pm[0m
[1;34m[2024-05-28T07:18:06.954431Z] [debug] [pid:73784] ||| finished firstboot_license_agreement installation/yast_firstboot (runtime: 9 s)[0m
[1;34m[2024-05-28T07:18:06.955261Z] [debug] [pid:73784] ||| starting validate_timezone_configuration tests/installation/clock_and_timezone/validate_timezone_configuration.pm[0m
[1;34m[2024-05-28T07:18:13.036493Z] [debug] [pid:73784] ||| finished validate_timezone_configuration installation/clock_and_timezone (runtime: 7 s)[0m
[1;34m[2024-05-28T07:18:13.037450Z] [debug] [pid:73784] ||| starting accept_timezone_configuration tests/installation/clock_and_timezone/accept_timezone_configuration.pm[0m
[1;34m[2024-05-28T07:18:16.106057Z] [debug] [pid:73784] ||| finished accept_timezone_configuration installation/clock_and_timezone (runtime: 3 s)[0m
[1;34m[2024-05-28T07:18:16.106885Z] [debug] [pid:73784] ||| starting enable_autologin tests/installation/authentication/enable_autologin.pm[0m
[1;34m[2024-05-28T07:18:20.262800Z] [debug] [pid:73784] ||| finished enable_autologin installation/authentication (runtime: 4 s)[0m
[1;34m[2024-05-28T07:18:20.263646Z] [debug] [pid:73784] ||| starting firstboot_user_simple_pwd tests/installation/authentication/firstboot_user_simple_pwd.pm[0m
[1;34m[2024-05-28T07:18:31.495663Z] [debug] [pid:73784] ||| finished firstboot_user_simple_pwd installation/authentication (runtime: 11 s)[0m
[1;34m[2024-05-28T07:18:31.496505Z] [debug] [pid:73784] ||| starting root_simple_pwd tests/installation/authentication/root_simple_pwd.pm[0m
[1;34m[2024-05-28T07:18:40.578078Z] [debug] [pid:73784] ||| finished root_simple_pwd installation/authentication (runtime: 9 s)[0m
[1;34m[2024-05-28T07:18:40.579048Z] [debug] [pid:73784] ||| starting firstboot_finish_setup tests/installation/yast_firstboot/firstboot_finish_setup.pm[0m
[1;34m[2024-05-28T07:18:45.647220Z] [debug] [pid:73784] ||| finished firstboot_finish_setup installation/yast_firstboot (runtime: 5 s)[0m
[1;34m[2024-05-28T07:18:45.648057Z] [debug] [pid:73784] ||| starting first_boot tests/installation/first_boot.pm[0m
[2024-05-28T07:18:45.648673Z] [debug] [pid:73784] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:818 called testapi::check_screen
[2024-05-28T07:18:45.648791Z] [debug] [pid:73784] <<< testapi::check_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome",
    "gnome-activities"
  ], timeout=30)
[31m[2024-05-28T07:18:48.377206Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.72 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:18:48.377296Z] [debug] [pid:73980] no match: 29.9s, best candidate: application_starts_on_login-WRONG-XTERM-generic-desktop-20221129 (0.00)[0m
[31m[2024-05-28T07:18:50.478956Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.10 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:18:50.479051Z] [debug] [pid:73980] no match: 27.2s, best candidate: consoletest_finish-gnome-20191211 (0.23)[0m
[31m[2024-05-28T07:18:55.978772Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 5.50 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:18:55.978863Z] [debug] [pid:73980] no match: 25.1s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)[0m
[31m[2024-05-28T07:18:57.947301Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 1.96 seconds for 122 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:18:57.947402Z] [debug] [pid:73980] no match: 19.6s, best candidate: gnome-activities-leap154-20221223 (0.92)[0m
[32m[2024-05-28T07:18:59.837682Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found gnome-activities-20240321, similarity 1.00 @ 0/2[0m
[2024-05-28T07:18:59.838879Z] [debug] [pid:73784] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:826 called testapi::send_key
[2024-05-28T07:18:59.839021Z] [debug] [pid:73784] <<< testapi::send_key(key="esc", wait_screen_change=0)
[2024-05-28T07:19:00.110369Z] [debug] [pid:73784] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:832 called testapi::assert_screen
[2024-05-28T07:19:00.110531Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch=[
    "generic-desktop",
    "emergency-shell",
    "emergency-mode",
    "opensuse-welcome"
  ], timeout=30)
[31m[2024-05-28T07:19:02.559067Z] [warn] [pid:73980] !!! backend::baseclass::check_asserted_screen: check_asserted_screen took 2.45 seconds for 98 candidate needles - make your needles more specific[0m
[37m[2024-05-28T07:19:02.559160Z] [debug] [pid:73980] no match: 29.9s, best candidate: opensuse-welcome-gnome-in-activites-20240514 (0.97)[0m
[32m[2024-05-28T07:19:04.197566Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found opensuse-welcome-show-on-boot-gnome-20240514, similarity 1.00 @ 632/595[0m
[2024-05-28T07:19:04.198210Z] [debug] [pid:73784] tests/installation/first_boot.pm:23 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:841 called testapi::mouse_hide
[2024-05-28T07:19:04.198298Z] [debug] [pid:73784] <<< testapi::mouse_hide(border_offset=1)
[37m[2024-05-28T07:19:04.198930Z] [debug] [pid:73980] mouse_move 1022, 766[0m
[37m[2024-05-28T07:19:04.199009Z] [debug] [pid:73980] send_pointer_event 0, 1022, 766, 1[0m
[1;34m[2024-05-28T07:19:04.199666Z] [debug] [pid:73784] ||| finished first_boot installation (runtime: 19 s)[0m
[37m[2024-05-28T07:19:04.202217Z] [debug] [pid:73784] Creating a VM snapshot lastgood[0m
[37m[2024-05-28T07:19:04.202868Z] [debug] [pid:73980] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[3]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":660009,"seconds":1716879898}}[0m
[37m[2024-05-28T07:19:04.202983Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"45200","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":181728,"seconds":1716880251}}[0m
[37m[2024-05-28T07:19:04.203078Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"42510","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":181953,"seconds":1716880251}}[0m
[37m[2024-05-28T07:19:04.203170Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"42510","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":183204,"seconds":1716880251}}[0m
[37m[2024-05-28T07:19:04.203261Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"42510","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":461775,"seconds":1716880256}}[0m
[37m[2024-05-28T07:19:04.203349Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"54650","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":462048,"seconds":1716880256}}[0m
[37m[2024-05-28T07:19:04.203433Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"54650","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":463302,"seconds":1716880256}}[0m
[37m[2024-05-28T07:19:04.203522Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"54650","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":179798,"seconds":1716880527}}[0m
[37m[2024-05-28T07:19:04.203607Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48158","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":180104,"seconds":1716880527}}[0m
[37m[2024-05-28T07:19:04.203704Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48158","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":181706,"seconds":1716880527}}[0m
[37m[2024-05-28T07:19:04.203796Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48158","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":806851,"seconds":1716880567}}[0m
[37m[2024-05-28T07:19:04.203882Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41028","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":807092,"seconds":1716880567}}[0m
[37m[2024-05-28T07:19:04.203968Z] [debug] [pid:73980] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"41028","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6014","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":808443,"seconds":1716880567}}[0m
[37m[2024-05-28T07:19:04.204062Z] [debug] [pid:73980] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":387088,"seconds":1716880576}}[0m
[37m[2024-05-28T07:19:04.204137Z] [debug] [pid:73980] EVENT {"data":{"guest":true,"reason":"guest-reset"},"event":"RESET","timestamp":{"microseconds":401229,"seconds":1716880576}}[0m
[37m[2024-05-28T07:19:04.204229Z] [debug] [pid:73980] Saving snapshot (Current VM state is running)[0m
[37m[2024-05-28T07:19:04.223780Z] [debug] [pid:73980] EVENT {"event":"STOP","timestamp":{"microseconds":223688,"seconds":1716880744}}[0m
[37m[2024-05-28T07:19:04.229219Z] [debug] [pid:73980] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0','snapshot-file' => '/var/lib/openqa/pool/24/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T07:19:04.233196Z] [debug] [pid:73980] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'cd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/24/raid/cd0-overlay1','snapshot-node-name' => 'cd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}[0m
[37m[2024-05-28T07:19:04.236528Z] [debug] [pid:73980] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":236440,"seconds":1716880744}}[0m
[37m[2024-05-28T07:19:04.736949Z] [debug] [pid:73980] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":257990,"seconds":1716880744}}[0m
[37m[2024-05-28T07:19:04.737070Z] [debug] [pid:73980] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":258086,"seconds":1716880744}}[0m
[37m[2024-05-28T07:19:04.737218Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:04.737268Z] [debug] [pid:73980] Migrating remaining bytes:   	1611907072[0m
[37m[2024-05-28T07:19:05.237800Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:05.237861Z] [debug] [pid:73980] Migrating remaining bytes:   	1592180736[0m
[37m[2024-05-28T07:19:05.738410Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:05.738471Z] [debug] [pid:73980] Migrating remaining bytes:   	1574010880[0m
[37m[2024-05-28T07:19:06.239033Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:06.239092Z] [debug] [pid:73980] Migrating remaining bytes:   	1555431424[0m
[37m[2024-05-28T07:19:06.739668Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:06.739728Z] [debug] [pid:73980] Migrating remaining bytes:   	1535447040[0m
[37m[2024-05-28T07:19:07.240237Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:07.240296Z] [debug] [pid:73980] Migrating remaining bytes:   	1519489024[0m
[37m[2024-05-28T07:19:07.740794Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:07.740853Z] [debug] [pid:73980] Migrating remaining bytes:   	1504989184[0m
[37m[2024-05-28T07:19:08.241343Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:08.241400Z] [debug] [pid:73980] Migrating remaining bytes:   	1492054016[0m
[37m[2024-05-28T07:19:08.741857Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:08.741914Z] [debug] [pid:73980] Migrating remaining bytes:   	1475297280[0m
[37m[2024-05-28T07:19:09.242436Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:09.242494Z] [debug] [pid:73980] Migrating remaining bytes:   	1461796864[0m
[37m[2024-05-28T07:19:09.742926Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:09.742984Z] [debug] [pid:73980] Migrating remaining bytes:   	1440690176[0m
[37m[2024-05-28T07:19:10.243487Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:10.243548Z] [debug] [pid:73980] Migrating remaining bytes:   	1424191488[0m
[37m[2024-05-28T07:19:10.744143Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:10.744213Z] [debug] [pid:73980] Migrating remaining bytes:   	1404293120[0m
[37m[2024-05-28T07:19:11.244897Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:11.244981Z] [debug] [pid:73980] Migrating remaining bytes:   	1386934272[0m
[37m[2024-05-28T07:19:11.745496Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:11.745555Z] [debug] [pid:73980] Migrating remaining bytes:   	1369952256[0m
[37m[2024-05-28T07:19:12.246106Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:12.246165Z] [debug] [pid:73980] Migrating remaining bytes:   	1350615040[0m
[37m[2024-05-28T07:19:12.746710Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:12.746768Z] [debug] [pid:73980] Migrating remaining bytes:   	1324257280[0m
[37m[2024-05-28T07:19:13.247217Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:13.247279Z] [debug] [pid:73980] Migrating remaining bytes:   	1303744512[0m
[37m[2024-05-28T07:19:13.747793Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:13.747853Z] [debug] [pid:73980] Migrating remaining bytes:   	1288339456[0m
[37m[2024-05-28T07:19:14.248546Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:14.248625Z] [debug] [pid:73980] Migrating remaining bytes:   	1271091200[0m
[37m[2024-05-28T07:19:14.749324Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:14.749419Z] [debug] [pid:73980] Migrating remaining bytes:   	1254903808[0m
[37m[2024-05-28T07:19:15.249936Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:15.249996Z] [debug] [pid:73980] Migrating remaining bytes:   	1239883776[0m
[37m[2024-05-28T07:19:15.750732Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:15.750813Z] [debug] [pid:73980] Migrating remaining bytes:   	1218834432[0m
[37m[2024-05-28T07:19:16.251777Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:16.251882Z] [debug] [pid:73980] Migrating remaining bytes:   	1202696192[0m
[37m[2024-05-28T07:19:16.752446Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:16.752518Z] [debug] [pid:73980] Migrating remaining bytes:   	1185746944[0m
[37m[2024-05-28T07:19:17.253020Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:17.253091Z] [debug] [pid:73980] Migrating remaining bytes:   	1169281024[0m
[37m[2024-05-28T07:19:17.753772Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:17.753852Z] [debug] [pid:73980] Migrating remaining bytes:   	1149382656[0m
[37m[2024-05-28T07:19:18.254546Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:18.254628Z] [debug] [pid:73980] Migrating remaining bytes:   	1131495424[0m
[37m[2024-05-28T07:19:18.755518Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:18.755620Z] [debug] [pid:73980] Migrating remaining bytes:   	1114906624[0m
[37m[2024-05-28T07:19:19.256197Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:19.256258Z] [debug] [pid:73980] Migrating remaining bytes:   	1099001856[0m
[37m[2024-05-28T07:19:19.756723Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:19.756785Z] [debug] [pid:73980] Migrating remaining bytes:   	1083547648[0m
[37m[2024-05-28T07:19:20.257235Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:20.257285Z] [debug] [pid:73980] Migrating remaining bytes:   	1067188224[0m
[37m[2024-05-28T07:19:20.757914Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:20.757979Z] [debug] [pid:73980] Migrating remaining bytes:   	1051254784[0m
[37m[2024-05-28T07:19:21.258581Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:21.258652Z] [debug] [pid:73980] Migrating remaining bytes:   	1035259904[0m
[37m[2024-05-28T07:19:21.759394Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:21.759500Z] [debug] [pid:73980] Migrating remaining bytes:   	1019768832[0m
[37m[2024-05-28T07:19:22.260068Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:22.260129Z] [debug] [pid:73980] Migrating remaining bytes:   	1003220992[0m
[37m[2024-05-28T07:19:22.760692Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:22.760752Z] [debug] [pid:73980] Migrating remaining bytes:   	986562560[0m
[37m[2024-05-28T07:19:23.261231Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:23.261290Z] [debug] [pid:73980] Migrating remaining bytes:   	970129408[0m
[37m[2024-05-28T07:19:23.761889Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:23.761948Z] [debug] [pid:73980] Migrating remaining bytes:   	953364480[0m
[37m[2024-05-28T07:19:24.262568Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:24.262633Z] [debug] [pid:73980] Migrating remaining bytes:   	936812544[0m
[37m[2024-05-28T07:19:24.763246Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:24.763319Z] [debug] [pid:73980] Migrating remaining bytes:   	920399872[0m
[37m[2024-05-28T07:19:25.263902Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:25.263959Z] [debug] [pid:73980] Migrating remaining bytes:   	904175616[0m
[37m[2024-05-28T07:19:25.764792Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:25.764908Z] [debug] [pid:73980] Migrating remaining bytes:   	887128064[0m
[37m[2024-05-28T07:19:26.265561Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:26.265653Z] [debug] [pid:73980] Migrating remaining bytes:   	869777408[0m
[37m[2024-05-28T07:19:26.766323Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:26.766396Z] [debug] [pid:73980] Migrating remaining bytes:   	852365312[0m
[37m[2024-05-28T07:19:27.267Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:27.267058Z] [debug] [pid:73980] Migrating remaining bytes:   	835313664[0m
[37m[2024-05-28T07:19:27.767685Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:27.767772Z] [debug] [pid:73980] Migrating remaining bytes:   	819396608[0m
[37m[2024-05-28T07:19:28.268392Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:28.268461Z] [debug] [pid:73980] Migrating remaining bytes:   	803799040[0m
[37m[2024-05-28T07:19:28.769131Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:28.769209Z] [debug] [pid:73980] Migrating remaining bytes:   	787521536[0m
[37m[2024-05-28T07:19:29.269963Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:29.270049Z] [debug] [pid:73980] Migrating remaining bytes:   	772579328[0m
[37m[2024-05-28T07:19:29.770673Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:29.770740Z] [debug] [pid:73980] Migrating remaining bytes:   	755847168[0m
[37m[2024-05-28T07:19:30.271420Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:30.271481Z] [debug] [pid:73980] Migrating remaining bytes:   	739905536[0m
[37m[2024-05-28T07:19:30.772094Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:30.772160Z] [debug] [pid:73980] Migrating remaining bytes:   	714416128[0m
[37m[2024-05-28T07:19:31.272859Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:31.272932Z] [debug] [pid:73980] Migrating remaining bytes:   	695349248[0m
[37m[2024-05-28T07:19:31.773592Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:31.773665Z] [debug] [pid:73980] Migrating remaining bytes:   	679452672[0m
[37m[2024-05-28T07:19:32.274358Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:32.274423Z] [debug] [pid:73980] Migrating remaining bytes:   	662401024[0m
[37m[2024-05-28T07:19:32.775169Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:32.775235Z] [debug] [pid:73980] Migrating remaining bytes:   	645943296[0m
[37m[2024-05-28T07:19:33.275880Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:33.275943Z] [debug] [pid:73980] Migrating remaining bytes:   	627351552[0m
[37m[2024-05-28T07:19:33.776646Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:33.776715Z] [debug] [pid:73980] Migrating remaining bytes:   	611860480[0m
[37m[2024-05-28T07:19:34.277350Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:34.277407Z] [debug] [pid:73980] Migrating remaining bytes:   	595767296[0m
[37m[2024-05-28T07:19:34.778075Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:34.778151Z] [debug] [pid:73980] Migrating remaining bytes:   	579170304[0m
[37m[2024-05-28T07:19:35.278740Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:35.278807Z] [debug] [pid:73980] Migrating remaining bytes:   	562401280[0m
[37m[2024-05-28T07:19:35.779443Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:35.779512Z] [debug] [pid:73980] Migrating remaining bytes:   	545759232[0m
[37m[2024-05-28T07:19:36.280070Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:36.280133Z] [debug] [pid:73980] Migrating remaining bytes:   	529084416[0m
[37m[2024-05-28T07:19:36.781101Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:36.781206Z] [debug] [pid:73980] Migrating remaining bytes:   	512872448[0m
[37m[2024-05-28T07:19:37.281915Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:37.281997Z] [debug] [pid:73980] Migrating remaining bytes:   	495890432[0m
[37m[2024-05-28T07:19:37.782887Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:37.782981Z] [debug] [pid:73980] Migrating remaining bytes:   	479600640[0m
[37m[2024-05-28T07:19:38.283966Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:38.284125Z] [debug] [pid:73980] Migrating remaining bytes:   	463732736[0m
[37m[2024-05-28T07:19:38.785099Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:38.785200Z] [debug] [pid:73980] Migrating remaining bytes:   	448913408[0m
[37m[2024-05-28T07:19:39.285776Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:39.285839Z] [debug] [pid:73980] Migrating remaining bytes:   	431861760[0m
[37m[2024-05-28T07:19:39.786479Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:39.786540Z] [debug] [pid:73980] Migrating remaining bytes:   	414175232[0m
[37m[2024-05-28T07:19:40.287214Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:40.287307Z] [debug] [pid:73980] Migrating remaining bytes:   	394698752[0m
[37m[2024-05-28T07:19:40.788052Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:40.788136Z] [debug] [pid:73980] Migrating remaining bytes:   	379207680[0m
[37m[2024-05-28T07:19:41.288852Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:41.288933Z] [debug] [pid:73980] Migrating remaining bytes:   	360230912[0m
[37m[2024-05-28T07:19:41.789566Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:41.789633Z] [debug] [pid:73980] Migrating remaining bytes:   	339648512[0m
[37m[2024-05-28T07:19:42.290417Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:42.290501Z] [debug] [pid:73980] Migrating remaining bytes:   	321044480[0m
[37m[2024-05-28T07:19:42.791480Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:42.791577Z] [debug] [pid:73980] Migrating remaining bytes:   	302219264[0m
[37m[2024-05-28T07:19:43.292532Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:43.292595Z] [debug] [pid:73980] Migrating remaining bytes:   	275505152[0m
[37m[2024-05-28T07:19:43.793057Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:43.793118Z] [debug] [pid:73980] Migrating remaining bytes:   	254214144[0m
[37m[2024-05-28T07:19:44.293668Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:44.293728Z] [debug] [pid:73980] Migrating remaining bytes:   	238223360[0m
[37m[2024-05-28T07:19:44.794391Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:44.794445Z] [debug] [pid:73980] Migrating remaining bytes:   	222089216[0m
[37m[2024-05-28T07:19:45.295003Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:45.295056Z] [debug] [pid:73980] Migrating remaining bytes:   	202051584[0m
[37m[2024-05-28T07:19:45.795765Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:45.795838Z] [debug] [pid:73980] Migrating remaining bytes:   	183771136[0m
[37m[2024-05-28T07:19:46.296496Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:46.296565Z] [debug] [pid:73980] Migrating remaining bytes:   	165257216[0m
[37m[2024-05-28T07:19:46.797226Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:46.797295Z] [debug] [pid:73980] Migrating remaining bytes:   	145719296[0m
[37m[2024-05-28T07:19:47.297955Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:47.298022Z] [debug] [pid:73980] Migrating remaining bytes:   	127762432[0m
[37m[2024-05-28T07:19:47.798653Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:47.798733Z] [debug] [pid:73980] Migrating remaining bytes:   	104480768[0m
[37m[2024-05-28T07:19:48.299368Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:48.299434Z] [debug] [pid:73980] Migrating remaining bytes:   	83083264[0m
[37m[2024-05-28T07:19:48.800126Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:48.800206Z] [debug] [pid:73980] Migrating remaining bytes:   	22192128[0m
[37m[2024-05-28T07:19:49.300574Z] [debug] [pid:73980] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":982098,"seconds":1716880788}}[0m
[37m[2024-05-28T07:19:49.300694Z] [debug] [pid:73980] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":995655,"seconds":1716880788}}[0m
[37m[2024-05-28T07:19:49.300772Z] [debug] [pid:73980] EVENT {"data":{"pass":4},"event":"MIGRATION_PASS","timestamp":{"microseconds":995855,"seconds":1716880788}}[0m
[37m[2024-05-28T07:19:49.300843Z] [debug] [pid:73980] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":999872,"seconds":1716880788}}[0m
[37m[2024-05-28T07:19:49.300959Z] [debug] [pid:73980] Migrating total bytes:     	1628250112[0m
[37m[2024-05-28T07:19:49.301004Z] [debug] [pid:73980] Migrating remaining bytes:   	0[0m
[37m[2024-05-28T07:19:49.301386Z] [debug] [pid:73980] Snapshot complete[0m
[37m[2024-05-28T07:19:50.652082Z] [debug] [pid:73980] EVENT {"event":"RESUME","timestamp":{"microseconds":651861,"seconds":1716880790}}[0m
[1;34m[2024-05-28T07:19:50.703617Z] [debug] [pid:73784] ||| starting validate_yast2_firstboot_configuration tests/console/validate_yast2_firstboot_configuration.pm[0m
[37m[2024-05-28T07:19:50.705761Z] [debug] [pid:73980] QEMU: Formatting '/var/lib/openqa/pool/24/raid/hd0-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=21474836480 backing_file=/var/lib/openqa/pool/24/raid/hd0 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[37m[2024-05-28T07:19:50.705830Z] [debug] [pid:73980] QEMU: Formatting '/var/lib/openqa/pool/24/raid/cd0-overlay1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=4497342464 backing_file=/var/lib/openqa/pool/24/raid/cd0-overlay0 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16[0m
[2024-05-28T07:19:50.706691Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console
[2024-05-28T07:19:50.706796Z] [debug] [pid:73784] <<< testapi::select_console(testapi_console="root-console")
[37m[2024-05-28T07:19:51.114082Z] [debug] [pid:73784] activate_console, console: root-console, type: console[0m
[2024-05-28T07:19:51.114386Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:857 called testapi::wait_still_screen
[2024-05-28T07:19:51.114548Z] [debug] [pid:73784] <<< testapi::wait_still_screen(similarity_level=47, stilltime=1, timeout=30)
[32m[2024-05-28T07:19:52.712294Z] [debug] [pid:73784] >>> testapi::wait_still_screen: detected same image for 1 seconds (1.59353613853455 s elapsed), last detected similarity is 1000000[0m
[2024-05-28T07:19:52.712510Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:862 called testapi::assert_screen
[2024-05-28T07:19:52.712685Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch=[
    "tty6-selected",
    "text-logged-in-root"
  ], timeout=60)
[32m[2024-05-28T07:19:52.820636Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found login-prompt-centos-20210810, similarity 1.00 @ 63/98[0m
[2024-05-28T07:19:52.821397Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:864 called testapi::enter_cmd
[2024-05-28T07:19:52.821568Z] [debug] [pid:73784] <<< testapi::type_string(string="root\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:19:52.990678Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:70 called testapi::assert_screen
[2024-05-28T07:19:52.990812Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch="password-prompt", timeout=60)
[32m[2024-05-28T07:19:53.840902Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found password-prompt-20160812, similarity 1.00 @ 0/112[0m
[2024-05-28T07:19:53.841091Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:79 called testapi::type_password
[2024-05-28T07:19:53.841257Z] [debug] [pid:73784] <<< testapi::type_string(string="[masked]", max_interval=100, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:19:55.045825Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:865 called susedistribution::handle_password_prompt -> lib/susedistribution.pm:81 called testapi::send_key
[2024-05-28T07:19:55.045990Z] [debug] [pid:73784] <<< testapi::send_key(key="ret", wait_screen_change=0)
[2024-05-28T07:19:55.313765Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:876 called testapi::assert_screen
[2024-05-28T07:19:55.313923Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch="text-logged-in-root", timeout=60)
[37m[2024-05-28T07:19:55.325714Z] [debug] [pid:73980] no match: 59.9s, best candidate: text-logged-in-root-20170627 (0.78)[0m
[32m[2024-05-28T07:19:56.370124Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found text-logged-in-root-20151204, similarity 1.00 @ 55/144[0m
[2024-05-28T07:19:56.370328Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:879 called testapi::assert_screen
[2024-05-28T07:19:56.370430Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch="root-console", timeout=30)
[32m[2024-05-28T07:19:57.390502Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/144[0m
[2024-05-28T07:19:57.390863Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:19:57.391078Z] [debug] [pid:73784] <<< testapi::type_string(string="setterm -blank 0", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:19:57.931069Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:19:57.931345Z] [debug] [pid:73784] <<< testapi::type_string(string="; echo YpuUt-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:19:59.043952Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:933 called distribution::script_run
[2024-05-28T07:19:59.044221Z] [debug] [pid:73784] <<< testapi::wait_serial(no_regex=0, expect_not_found=0, timeout=30, regexp=qr/YpuUt-\d+-/u, buffer_size=undef, quiet=undef, record_output=undef)
[32m[2024-05-28T07:20:00.089758Z] [debug] [pid:73784] >>> testapi::wait_serial: (?^u:YpuUt-\d+-): ok[0m
[2024-05-28T07:20:00.090012Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:27 called testapi::select_console -> lib/susedistribution.pm:997 called testapi::assert_screen
[2024-05-28T07:20:00.090123Z] [debug] [pid:73784] <<< testapi::assert_screen(mustmatch="root-console", timeout=30, no_wait=1)
[32m[2024-05-28T07:20:00.138222Z] [debug] [pid:73784] >>> testapi::_handle_found_needle: found root-console-20180724, similarity 1.00 @ 80/160[0m
Use of uninitialized value $username in concatenation (.) or string at opensuse/tests/console/validate_yast2_firstboot_configuration.pm line 20.
	validate_yast2_firstboot_configuration::assert_user_exist(undef) called at opensuse/tests/console/validate_yast2_firstboot_configuration.pm line 33
	validate_yast2_firstboot_configuration::run(validate_yast2_firstboot_configuration=HASH(0x55712b6bf3f0)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(validate_yast2_firstboot_configuration=HASH(0x55712b6bf3f0)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0), CODE(0x55712b700600)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x557124013d80)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
Use of uninitialized value $username in concatenation (.) or string at opensuse/tests/console/validate_yast2_firstboot_configuration.pm line 20.
	validate_yast2_firstboot_configuration::assert_user_exist(undef) called at opensuse/tests/console/validate_yast2_firstboot_configuration.pm line 33
	validate_yast2_firstboot_configuration::run(validate_yast2_firstboot_configuration=HASH(0x55712b6bf3f0)) called at /usr/lib/os-autoinst/basetest.pm line 352
	eval {...} called at /usr/lib/os-autoinst/basetest.pm line 346
	basetest::runtest(validate_yast2_firstboot_configuration=HASH(0x55712b6bf3f0)) called at /usr/lib/os-autoinst/autotest.pm line 416
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 416
	autotest::runalltests() called at /usr/lib/os-autoinst/autotest.pm line 273
	eval {...} called at /usr/lib/os-autoinst/autotest.pm line 273
	autotest::run_all() called at /usr/lib/os-autoinst/autotest.pm line 324
	autotest::__ANON__(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	eval {...} called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 329
	Mojo::IOLoop::ReadWriteProcess::_fork(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0), CODE(0x55712b700600)) called at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 492
	Mojo::IOLoop::ReadWriteProcess::start(Mojo::IOLoop::ReadWriteProcess=HASH(0x55712bea38e0)) called at /usr/lib/os-autoinst/autotest.pm line 326
	autotest::start_process() called at /usr/lib/os-autoinst/OpenQA/Isotovideo/Runner.pm line 103
	OpenQA::Isotovideo::Runner::start_autotest(OpenQA::Isotovideo::Runner=HASH(0x557124013d80)) called at /usr/bin/isotovideo line 172
	eval {...} called at /usr/bin/isotovideo line 161
[2024-05-28T07:20:00.139076Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:33 called validate_yast2_firstboot_configuration::assert_user_exist -> tests/console/validate_yast2_firstboot_configuration.pm:20 called testapi::assert_script_run
[2024-05-28T07:20:00.139201Z] [debug] [pid:73784] <<< testapi::assert_script_run(cmd="id ", quiet=undef, fail_message="User  not found in the system, though it is expected to be created by YaST Firstboot", timeout=90)
[2024-05-28T07:20:00.139311Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:33 called validate_yast2_firstboot_configuration::assert_user_exist -> tests/console/validate_yast2_firstboot_configuration.pm:20 called testapi::assert_script_run
[2024-05-28T07:20:00.139416Z] [debug] [pid:73784] <<< testapi::type_string(string="id ", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:20:00.241648Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:33 called validate_yast2_firstboot_configuration::assert_user_exist -> tests/console/validate_yast2_firstboot_configuration.pm:20 called testapi::assert_script_run
[2024-05-28T07:20:00.241862Z] [debug] [pid:73784] <<< testapi::type_string(string="; echo hMW3O-\$?- > /dev/ttyS0\n", max_interval=250, wait_screen_change=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2024-05-28T07:20:01.372302Z] [debug] [pid:73784] tests/console/validate_yast2_firstboot_configuration.pm:33 called validate_yast2_firstboot_configuration::assert_user_exist -> tests/console/validate_yast2_firstboot_configuration.pm:20 called testapi::assert_script_run
[2024-05-28T07:20:01.372531Z] [debug] [pid:73784] <<< testapi::wait_serial(expect_not_found=0, no_regex=0, buffer_size=undef, regexp=qr/hMW3O-\d+-/u, timeout=90, record_output=undef, quiet=undef)
[32m[2024-05-28T07:20:02.422039Z] [debug] [pid:73784] >>> testapi::wait_serial: (?^u:hMW3O-\d+-): ok[0m
[1;34m[2024-05-28T07:20:02.422533Z] [debug] [pid:73784] ||| finished validate_yast2_firstboot_configuration console (runtime: 12 s)[0m
[37m[2024-05-28T07:20:02.424311Z] [debug] [pid:73306] stopping autotest process 73784[0m
[37m[2024-05-28T07:20:02.435090Z] [debug] [pid:73306] [autotest] process exited: 0[0m
[37m[2024-05-28T07:20:02.535378Z] [debug] [pid:73306] done with autotest process[0m
[37m[2024-05-28T07:20:02.535696Z] [debug] [pid:73306] stopping command server 73330 because test execution ended[0m
[37m[2024-05-28T07:20:02.535775Z] [debug] [pid:73306] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20243/4aPEXtdmIuNlGqc0/broadcast[0m
[37m[2024-05-28T07:20:02.548895Z] [debug] [pid:73306] commands process exited: 0[0m
[37m[2024-05-28T07:20:02.649178Z] [debug] [pid:73306] done with command server[0m
[37m[2024-05-28T07:20:02.649288Z] [debug] [pid:73306] isotovideo done[0m
[37m[2024-05-28T07:20:02.650233Z] [debug] [pid:73980] QEMU status is not 'shutdown', it is 'running'[0m
[37m[2024-05-28T07:20:02.650464Z] [debug] [pid:73306] backend shutdown state: [0m
[33m[2024-05-28T07:20:02.650946Z] [info] [pid:73980] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json[0m
[37m[2024-05-28T07:20:03.704565Z] [debug] [pid:73980] Passing remaining frames to the video encoder[0m
frame=  807 fps=0.7 q=0.0 Lsize=     935kB time=00:00:33.58 bitrate= 228.1kbits/s speed=0.0288x    
video:929kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: 0.649884%
[37m[2024-05-28T07:20:04.127463Z] [debug] [pid:73980] Waiting for video encoder to finalize the video[0m
[37m[2024-05-28T07:20:04.127538Z] [debug] [pid:73980] The external video encoder (pid 74179) terminated[0m
[37m[2024-05-28T07:20:04.127587Z] [debug] [pid:73980] The built-in video encoder (pid 74180) terminated[0m
[37m[2024-05-28T07:20:04.128056Z] [debug] [pid:73980] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 73980 (/usr/bin/isotovideo: backen)[0m
[37m[2024-05-28T07:20:04.128541Z] [debug] [pid:73980] sending magic and exit[0m
[37m[2024-05-28T07:20:04.128772Z] [debug] [pid:73306] received magic close[0m
[37m[2024-05-28T07:20:04.186839Z] [debug] [pid:73306] backend process exited: 0[0m
Use of uninitialized value $name in pattern match (m//) at /usr/lib/os-autoinst/OpenQA/Isotovideo/Utils.pm line 332.
	OpenQA::Isotovideo::Utils::handle_generated_assets(OpenQA::Isotovideo::CommandHandler=HASH(0x55712d392c88), "") called at /usr/bin/isotovideo line 204
	eval {...} called at /usr/bin/isotovideo line 161
[37m[2024-05-28T07:20:04.288123Z] [debug] [pid:73306] stopping backend process 73980[0m
[37m[2024-05-28T07:20:04.288200Z] [debug] [pid:73306] done with backend process[0m
73306: EXIT 0
[2024-05-28T07:20:04.333853Z] [info] Isotovideo exit status: 0
[2024-05-28T07:20:04.356514Z] [info] +++ worker notes +++
[2024-05-28T07:20:04.356641Z] [info] End time: 2024-05-28 07:20:04
[2024-05-28T07:20:04.356709Z] [info] Result: done
[2024-05-28T07:20:04.359968Z] [info] Uploading autoyast_firstboot.xml
[2024-05-28T07:20:04.400057Z] [info] Uploading yui-log.txt
[2024-05-28T07:20:04.427366Z] [info] Uploading video.webm
[2024-05-28T07:20:04.475623Z] [info] Uploading autoinst-log.txt
